Skip to content

Record instructions retired alongside time in TIME_TRACE (depends on #928) - #929

Merged
quickbeam123 merged 2 commits into
masterfrom
martin-timetrace-instructions
Sep 14, 2026
Merged

quickbeam123 merged 2 commits into
masterfrom
martin-timetrace-instructions

Conversation

@quickbeam123

Copy link
Copy Markdown
Collaborator

A -tstat sweep is normally run many-ways parallel, and wall clock then measures the machine as much as the code: on the reference server, 120 concurrent jobs spread effective throughput from 1828 M instr/s at p10 to 4724 at p90, so a run at p10 takes 1.71x longer than the median for identical work. Ratios within one run survive that; per-node comparisons between runs do not.

Instruction counts do not have that problem. Measured on the same machine, a fixed workload retires 12000031 and 12000032 instructions across seven runs -- a spread of 0.0000%.

So each TIME_TRACE node now carries user-space instructions retired as well as elapsed time:

[root] (total: 39 ms, avg: 39 ms, cnt: 1, instr: 118 M)

Both are kept, deliberately. Part of that 2.6x throughput spread is genuine memory-boundedness rather than contention -- median throughput falls monotonically with peak memory, 4530 M instr/s under 64 MB down to 2672 at 256 MB-1 GB -- and an instructions-only trace would make a node that is slow because it is cache-missing look cheap. Time and instructions together give ns-per-instruction per node, which is what tells those two apart.

Reading the counter cheaply

Lib/Timer.cpp already opens a PERF_COUNT_HW_INSTRUCTIONS event but reads it with read(PERF_FD), which costs a syscall (~560ns measured) -- fine for the timer thread's 1ms limit check, hopeless for a scope entered ~10^9 times per run. The new Lib/PerfInstructions.hpp mmaps the same fd and reads the counter register directly with rdpmc under the metadata page's seqlock: 8.9ns measured, against 27.5ns for the clock_gettime the profiler already does per scope.

rdpmc reads the performance counter of whatever CPU the caller runs on, so it is only valid on the thread the event is attached to. Hence the split: ScopedTimer (main thread) takes the fast path, while printPretty -- which runs on timer_thread when a resource limit fires -- credits the still-open scopes using the new Timer::instructionCountAnyThread(), which goes through the fd. Everything degrades to "no measurement" rather than to a wrong number: non-x86, no cap_user_rdpmc, or an event not currently scheduled all yield -1, and the field then prints as "-" so the output format stays unconditional.

Two details worth knowing:

  • reads are ordered so the instruction interval nests inside the time interval (clock first on entry, instructions first on exit), which keeps the cost of the clock read itself out of the instruction count;
  • [root] is entered during static initialisation, long before the counter exists, so Timer::reinitialise() calls TimeTrace::rebaseInstructionCounters() once the event has been opened and reset. Without it the whole-run total would read 0.

instructionCountingAvailable() also refuses to report anything when the PMU is multiplexing this event (time_enabled != time_running), since the kernel then expects counts to be scaled, which would turn them into estimates and destroy the determinism that is the entire point.

Verified locally: unit tests 100/100, checks/sanity clean, output format correct. macOS has neither perf_event_open nor user-space PMU access, so the values themselves are NOT verified here -- they read "-". On Linux, check that [root]'s instr matches the independently-obtained "Instructions burned" statistics line (which reads the same event through read()), and that two -al-bounded runs of one problem agree to well under 0.1% per node while their times do not.

A -tstat sweep is normally run many-ways parallel, and wall clock then measures
the machine as much as the code: on the reference server, 120 concurrent jobs
spread effective throughput from 1828 M instr/s at p10 to 4724 at p90, so a run
at p10 takes 1.71x longer than the median for identical work. Ratios within one
run survive that; per-node comparisons between runs do not.

Instruction counts do not have that problem. Measured on the same machine, a
fixed workload retires 12000031 and 12000032 instructions across seven runs -- a
spread of 0.0000%.

So each TIME_TRACE node now carries user-space instructions retired as well as
elapsed time:

  [root] (total: 39 ms, avg: 39 ms, cnt: 1, instr: 118 M)

Both are kept, deliberately. Part of that 2.6x throughput spread is genuine
memory-boundedness rather than contention -- median throughput falls
monotonically with peak memory, 4530 M instr/s under 64 MB down to 2672 at
256 MB-1 GB -- and an instructions-only trace would make a node that is slow
because it is cache-missing look cheap. Time and instructions together give
ns-per-instruction per node, which is what tells those two apart.

Reading the counter cheaply

Lib/Timer.cpp already opens a PERF_COUNT_HW_INSTRUCTIONS event but reads it with
read(PERF_FD), which costs a syscall (~560ns measured) -- fine for the timer
thread's 1ms limit check, hopeless for a scope entered ~10^9 times per run. The
new Lib/PerfInstructions.hpp mmaps the same fd and reads the counter register
directly with rdpmc under the metadata page's seqlock: 8.9ns measured, against
27.5ns for the clock_gettime the profiler already does per scope.

rdpmc reads the performance counter of whatever CPU the *caller* runs on, so it
is only valid on the thread the event is attached to. Hence the split:
ScopedTimer (main thread) takes the fast path, while printPretty -- which runs on
timer_thread when a resource limit fires -- credits the still-open scopes using
the new Timer::instructionCountAnyThread(), which goes through the fd. Everything
degrades to "no measurement" rather than to a wrong number: non-x86, no
cap_user_rdpmc, or an event not currently scheduled all yield -1, and the field
then prints as "-" so the output format stays unconditional.

Two details worth knowing:

- reads are ordered so the instruction interval nests inside the time interval
  (clock first on entry, instructions first on exit), which keeps the cost of the
  clock read itself out of the instruction count;
- [root] is entered during static initialisation, long before the counter exists,
  so Timer::reinitialise() calls TimeTrace::rebaseInstructionCounters() once the
  event has been opened and reset. Without it the whole-run total would read 0.

instructionCountingAvailable() also refuses to report anything when the PMU is
multiplexing this event (time_enabled != time_running), since the kernel then
expects counts to be scaled, which would turn them into estimates and destroy the
determinism that is the entire point.

Verified locally: unit tests 100/100, checks/sanity clean, output format correct.
macOS has neither perf_event_open nor user-space PMU access, so the values
themselves are NOT verified here -- they read "-". On Linux, check that [root]'s
instr matches the independently-obtained "Instructions burned" statistics line
(which reads the same event through read()), and that two -al-bounded runs of one
problem agree to well under 0.1% per node while their times do not.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

@MichaelRawson MichaelRawson left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I will repeat my warning that this kind of DIY profiling may be misleading. Use something like perf record instead. But, with that caveat, this seems like an improvement.

Comment thread Lib/PerfInstructions.hpp
Base automatically changed from martin-timetrace-race to master September 11, 2026 17:22
Review feedback on the rdpmc helper: GCC does have an intrinsic for this, and
the __asm__ should be guarded so it cannot reach a compiler that would reject it.

Both hold. gcc/config/i386/ia32intrin.h defines

  extern __inline unsigned long long
  __attribute__((__gnu_inline__, __always_inline__, __artificial__))
  __rdpmc (int __S)
  { return __builtin_ia32_rdpmc (__S); }

and Clang's ia32intrin.h is the same one-liner around the same builtin. Neither
is behind a target pragma or needs an -m flag, unlike the SSE/AVX intrinsics
beside them. Calling the builtin directly keeps <x86intrin.h> -- some 40 000
preprocessed lines -- out of the two translation units that include this header.

The builtin is not subject to common-subexpression elimination, so two reads
still issue two rdpmc instructions, and it stays inside instructionCount()'s
seqlock retry loop; that is what the dropped __volatile__ was for. Verified with
clang 21 targeting x86_64: identical instruction sequence to the asm version,
and the one-read/two-read cases emit one and two rdpmc respectively.

The guard is strictly belt and braces rather than a fix: VAMPIRE_PERF_EXISTS
(Lib/Portability.hpp:22) is 0 unless __linux__ and <linux/perf_event.h>, and this
whole block sits inside it, so MSVC could never see the asm. Adding __GNUC__
states the requirement where the hazard is rather than three files away, and it
is needed just as much by the builtin as it was by the asm.

Not compile-checked against a real GCC: no x86 GCC is available here (the local
MacPorts gcc15 is aarch64-only and ships no x86 intrinsic headers), so the GCC
side rests on the upstream header above. Worth confirming on Linux before merge.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@quickbeam123
quickbeam123 merged commit 1254bdc into master Sep 14, 2026
1 check passed
@quickbeam123
quickbeam123 deleted the martin-timetrace-instructions branch September 14, 2026 09:45
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants